【Greengrass V2】Lambda コンポーネントのループ処理がデバイス外の要因で異常終了した時の動作を確認してみた

【Greengrass V2】Lambda コンポーネントのループ処理がデバイス外の要因で異常終了した時の動作を確認してみた

Greengrass V2 の Lambda コンポーネントでデバイス外の原因でエラーになったときの動作を確認してみました。
#Greengrass V2
#AWS IoT Greengrass
#AWS IoT
#AWS
市田善久

市田善久

facebook logohatena logotwitter logo
Clock Icon2021.08.27

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

前回の記事では、Lambda コンポーネントのプロセスを強制停止した動作を確認してみました。しかし実際に利用する中では、外部要因によりコンポーネントに異常が発生する可能性の方が高いかと思います。

そこで、今回は「センサー側の異常」が発生したことを想定して、コンポーネントの動作を確認してみました。また、その際の対応方法についても検証してみました。

前回の記事はこちらです。

想定するケース

構成はこれまでの同じで Modbus 対応センサーを使って温湿度データを取得するものになります。
（今回の検証環境はこれまでの環境をそのまま使っているだけなので、GPIO 経由で取得するセンサーなどでも同じ流れになると思います。）

10-loop-error-before

このセンサーは、私の環境では乾電池で動かしているので、乾電池を一つだけ抜いて「センサーが停止する」場面をシミュレーションしてみました。
（掃除中に思わず電源コードに足を引っ掛けて機器を止めた、とかよく聞く話です…）

11-loop-error1

Lambda コード

Lambda のコードは以前のものと同様です。

from pymodbus.client.sync import ModbusSerialClient as ModbusClient
import datetime
import time
import os

def run_sync_client():
    client = ModbusClient(baudrate=9600, port="/dev/ttyUSB0", method="rtu")
    client.connect()
    FilePath = os.environ["FilePath"] # Lambda の環境変数からデータ出力ファイルのパスを取得
    rr = client.read_input_registers(address=1, count=2, unit=0x1)
    temperature = rr.registers[0]/10
    humidity  = rr.registers[1]/10

    # Append the message to the log file.
    with open(FilePath, 'a') as f:
        print(f"{str(datetime.datetime.now())}\tTemperatur:\t{temperature} ℃", file=f)
        print(f"{str(datetime.datetime.now())}\tHumidity:\t{humidity} %", file=f)

    client.close()

while True:
    run_sync_client()
    time.sleep(10)


def lambda_handler(event, context):
    return

電池を抜いたら下記の箇所でセンサーに接続できず、while ループの途中でエラーとなるはずです。（スクリプトが停止するはず）

    client = ModbusClient(baudrate=9600, port="/dev/ttyUSB0", method="rtu")
    client.connect()

電池を抜いてセンサーを止めてみる

それでは実際にセンサーの電池を抜いて /greengrass/v2/logs/greengrass.log のログから動作を確認してみます。
電池を抜いてしばらくすると、前回の記事で確認したものと同じように「１回目のERRORED状態」に遷移しました。ERRORED状態になったので「自動復旧」を試みている様子が確認できました。
（見やすさのためログを部分的に抜粋・削除しています）

補足ですが、電池を抜くと Lambda のコードにあるとおりwhileループの途中でエラーになるので、このスクリプトは停止しているはずですが、ERROREDステータスになったコンポーネント( Lambda )は自動復旧により再起動が実行されるので再度ループ処理が再開されます。

2021-08-26T06:01:01.372Z [WARN] com.aws.greengrass.lambdamanager.Lambda: The lambda has not reported status within the specified timeout PT1M and will be restarted immediately.. {componentName=modbus-sensor-lambda-component}
2021-08-26T06:01:01.377Z [ERROR] com.aws.greengrass.lambdamanager.UserLambdaService: service-errored. {serviceName=modbus-sensor-lambda-component, currentState=RUNNING}
com.aws.greengrass.lambdamanager.StatusTimeoutException: Lambda status not received within timeout
    at com.aws.greengrass.lambdamanager.Lambda.lambda$createInstanceKeepAliveTask$5(Lambda.java:266)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
    at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
    at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:829)
    
2021-08-26T06:01:01.378Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: service-report-state. {serviceName=modbus-sensor-lambda-component, currentState=RUNNING, newState=ERRORED}
2021-08-26T06:01:01.391Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: service-report-state. {serviceName=modbus-sensor-lambda-component, currentState=ERRORED, newState=STOPPING}
2021-08-26T06:01:01.402Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: Shutdown initiated. {serviceName=modbus-sensor-lambda-component, currentState=STOPPING}
2021-08-26T06:01:01.765Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: service-report-state. {serviceName=modbus-sensor-lambda-component, currentState=STOPPING, newState=INSTALLED}
2021-08-26T06:01:01.767Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: service-report-state. {serviceName=modbus-sensor-lambda-component, currentState=INSTALLED, newState=STARTING}
2021-08-26T06:01:01.931Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: service-report-state. {serviceName=modbus-sensor-lambda-component, currentState=STARTING, newState=RUNNING}

電池を抜いた状態で引き続き待機します。

先程自動復旧が行われましたが、電池は抜いたままなのでセンサーにアクセスできず、約1分後に同じエラーが発生して「２回目のERRORED状態」になりました。そして再び自動復旧を試みる様子が確認できました。
（見やすさのためログを部分的に抜粋・削除しています）

2021-08-26T06:02:07.820Z [WARN] com.aws.greengrass.lambdamanager.Lambda: The lambda has not reported status within the specified timeout PT1M and will be restarted immediately.. {componentName=modbus-sensor-lambda-component}
2021-08-26T06:02:07.820Z [ERROR] com.aws.greengrass.lambdamanager.UserLambdaService: service-errored. {serviceInstance=0, serviceName=modbus-sensor-lambda-component, currentState=RUNNING}
com.aws.greengrass.lambdamanager.StatusTimeoutException: Lambda status not received within timeout
    at com.aws.greengrass.lambdamanager.Lambda.lambda$createInstanceKeepAliveTask$5(Lambda.java:266)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
    at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
    at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:829)

2021-08-26T06:02:07.821Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: service-report-state. {serviceInstance=0, serviceName=modbus-sensor-lambda-component, currentState=RUNNING, newState=ERRORED}
2021-08-26T06:02:07.822Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: service-report-state. {serviceName=modbus-sensor-lambda-component, currentState=ERRORED, newState=STOPPING}
2021-08-26T06:02:07.842Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: Shutdown initiated. {serviceName=modbus-sensor-lambda-component, currentState=STOPPING}
2021-08-26T06:02:08.121Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: service-report-state. {serviceName=modbus-sensor-lambda-component, currentState=STOPPING, newState=INSTALLED}
2021-08-26T06:02:08.122Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: service-report-state. {serviceInstance=0, serviceName=modbus-sensor-lambda-component, currentState=INSTALLED, newState=STARTING}
2021-08-26T06:02:08.282Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: service-report-state. {serviceName=modbus-sensor-lambda-component, currentState=STARTING, newState=RUNNING}

電池を抜いたまま更に待機していると、また同じようにエラーが発生しましたが、今回は「３回目のERRORED状態」になるので、自動復旧することなくBROKENステータスに遷移しました。
（見やすさのためログを部分的に抜粋・削除しています）

2021-08-26T06:03:14.173Z [WARN] com.aws.greengrass.lambdamanager.Lambda: The lambda has not reported status within the specified timeout PT1M and will be restarted immediately.. {componentName=modbus-sensor-lambda-component}
2021-08-26T06:03:14.174Z [ERROR] com.aws.greengrass.lambdamanager.UserLambdaService: service-errored. {serviceName=modbus-sensor-lambda-component, currentState=RUNNING}
com.aws.greengrass.lambdamanager.StatusTimeoutException: Lambda status not received within timeout
    at com.aws.greengrass.lambdamanager.Lambda.lambda$createInstanceKeepAliveTask$5(Lambda.java:266)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
    at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
    at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:829)

2021-08-26T06:03:14.175Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: service-report-state. {serviceName=modbus-sensor-lambda-component, currentState=RUNNING, newState=ERRORED}
2021-08-26T06:03:14.176Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: service-set-state. {serviceInstance=0, serviceName=modbus-sensor-lambda-component, currentState=RUNNING, newState=BROKEN}
2021-08-26T06:03:14.197Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: Shutdown initiated. {serviceInstance=0, serviceName=modbus-sensor-lambda-component, currentState=BROKEN}

コンポーネントのログも前回と同じログが出ており、こちらも2回自動復旧を試みて3回目にBROKENステータスになっていました。BROKENになったので、このLambda コンポーネントのプロセスも停止してなくなっていました。

$ ps aux |grep python3.7 |grep -v grep |wc -l
0

コンポーネントは停止しているので、指定ファイルへのデータ出力も止まっています。この状態を図にすると下記の様になります。

12-loop-error2

Lambda コードを修正して再デプロイ

次に、今回のエラー（pymodbusで センサーに接続できないエラー）に対応する為、下記のように例外処理を追加してコードを修正します。

期待する動作は次のとおりです。

  • 電池を抜いたらエラー内容を同じファイルに都度出力する
  • 電池を抜いてもスクリプトの例外処理により処理を継続する
    • エラーにならないのでコンポーネントがERRORED状態に遷移しない
  • 電池を戻したらセンサーデータの出力を再開する
from pymodbus.client.sync import ModbusSerialClient as ModbusClient
import datetime
import time
import os

# Lambda コンポーネントの環境変数からデータ出力ファイルのパスを取得
FilePath = os.environ["FilePath"] 

def run_sync_client():
    client = ModbusClient(baudrate=9600, port="/dev/ttyUSB0", method="rtu")
    client.connect()
    rr = client.read_input_registers(address=1, count=2, unit=0x1)
    temperature = rr.registers[0]/10
    humidity  = rr.registers[1]/10

    # Append the message to the log file.
    with open(FilePath, 'a') as f:
        print(f"{str(datetime.datetime.now())}\tTemperatur:\t{temperature} ℃", file=f)
        print(f"{str(datetime.datetime.now())}\tHumidity:\t{humidity} %", file=f)

    client.close()

while True:
    try:
        run_sync_client()
        time.sleep(10)
    except AttributeError as e: # ModbusIOException
        with open(FilePath, 'a') as f:
            print(f"{str(datetime.datetime.now())}\t{str(e)}", file=f)

def lambda_handler(event, context):
    return

デプロイに関して今回は具体的な更新方法は割愛しますが、手順は下記になります。

  • AWS SAM でコードを修正して Lambda にデプロイ
    • AWS SAM 以外の方法でも構いません。
  • Greengrass で新バージョンのコンポーネントを作成
    • 新バージョンの Lambda を指定して作成
  • 新バージョンのコンポーネントをデバイスにデプロイ

13-loop-error3-code-modify

コンポーネントの更新に関する具体的な手順は下記を参考にしていただければと思います。

コード修正後の動作確認

デプロイできたら改めて電池を外して確認してみましょう。
温湿度データが /tmp/data_path_new_default.log に出力されていましたが、電池を抜いたタイミングでエラー内容が記録されるようになりました。

2021-08-26 16:01:03.874313  Temperatur: 29.0 ℃
2021-08-26 16:01:03.874404  Humidity:   55.2 %
2021-08-26 16:01:16.904751  'ModbusIOException' object has no attribute 'registers'
2021-08-26 16:01:19.921373  'ModbusIOException' object has no attribute 'registers'
2021-08-26 16:01:22.937900  'ModbusIOException' object has no attribute 'registers'
2021-08-26 16:01:25.956669  'ModbusIOException' object has no attribute 'registers'

一方で/greengrass/v2/logs/greengrass.logとコンポーネントのログには、エラーに関するログは何も出ていませんでした。想定どおりコンポーネント的には正常動作とみなされている事が分かりました。

14-loop-error3

次に電池を戻してみると…センサーが動作し始めて温湿度データの出力が再開されました！
もちろんこの間/greengrass/v2/logs/greengrass.logには異常を示すようなログは何も出ていませんでした。

2021-08-26 16:02:44.395285  'ModbusIOException' object has no attribute 'registers'
2021-08-26 16:02:47.414736  'ModbusIOException' object has no attribute 'registers'
2021-08-26 16:02:47.574084  Temperatur: 28.5 ℃
2021-08-26 16:02:47.574169  Humidity:   53.1 %

15-loop-error-ok

注意点としては、上記でエラー発生時にセンサーデータが取得できていないですが、コンポーネントの状態はRUNNNINGで正常となり、実態と状態に「ズレ」があります。
そのため、下記のようにLambdaコードを修正することで、エラーメッセージをファイル出力しつつ、エラーの都度コンポーネントが終了するようになります。エラーが解消しなければ最終的にBROKENになります。BROKENになるので、センサーデータが取れない実態と整合性がとれるようになりますし、エラーを後から確認することも容易になります。

while True:
    try:
        run_sync_client()
        time.sleep(10)
    except AttributeError as e: # ModbusIOException
        with open(FilePath, 'a') as f:
            print(f"{str(datetime.datetime.now())}\t{str(e)}", file=f)
        time.sleep(5)
        sys.exit(1)

この場合の流れは下記のようになります。

  • 電池を抜くと、/tmp/data_path_new_default.logにエラーメッセージ出力
    • 'ModbusIOException' object has no attribute 'registers'
    • /tmp/greengrass/v2/logs/greengrass.logにはERRORED3回→BROKENのログ
    • ERROREDで自動復旧が発生する度に/tmp/data_path_new_default.logに下記エラーメッセージ
2021-08-30 11:57:59.569599	'ModbusIOException' object has no attribute 'registers'
　この後、1回目のERRORED状態→自動復旧

2021-08-30 11:59:21.902618	'ModbusIOException' object has no attribute 'registers'
　この後、2回目のERRORED状態→自動復旧

2021-08-30 12:00:28.367169	'ModbusIOException' object has no attribute 'registers'
　この後、3回目のERRORED状態→BROKEN

BROKENになるので復旧させるには再デプロイしないといけないですが、エラー内容をファイル出力して内容を確認できるようにしつつ、API の状態と実態が合うので分かりやすいです。
どのように実装するか利用者側の都合に合わせて設計することになります。

実際にはどうやって運用するべきか

今回は一例として「センサーに接続できないエラー」に対応するようにコードを修正しました。

実際に利用する場合は、次のような監視・運用方法が考えられますが、運用担当者や環境に応じて運用設計するのがいいかと思います。

  • 例外処理のエラーを専用のログファイルに出力してログ監視でエラーを検知・対応する
    • ログや現場確認から原因を特定して復旧
    • 状況によりコンポーネントを更新して再デプロイ
  • 例外処理で継続させずに/greengrass/v2/logs以下のログを監視してエラーを検知・対応する
    • ERROREDやBROKENのキーワードで監視
    • コンポーネントの状態を API などで監視
      • コンソールでも目視でエラーに気づきやすい
    • Greengrass デバイスの外部に原因がある場合、単純なコンポーネントの再デプロイでは復旧できない点に注意
      • 外部要因であればコンポーネントのコード修正は不要
      • 外部要因を解消してから再デプロイする必要がある
  • ネット接続が間欠的な環境であればリモートから検知できないので、現地で検知する仕組みも検討
    • 例：コンポーネントでエラーを判別してエッジ側の警告ライトを点滅させる

オマケ：例外処理の出力タイミング

先程の例外データ（ /tmp/data_path_new_default.log）の内容を眺めていて、エラー時のタイムスタンプが3秒間隔になっていました。本題とはずれますが「３秒間隔の原因」が気になったので追加で調べてみました。

2021-08-26 16:01:03.874313  Temperatur: 29.0 ℃
2021-08-26 16:01:03.874404  Humidity:   55.2 %
2021-08-26 16:01:16.904751  'ModbusIOException' object has no attribute 'registers'
2021-08-26 16:01:19.921373  'ModbusIOException' object has no attribute 'registers'
2021-08-26 16:01:22.937900  'ModbusIOException' object has no attribute 'registers'
2021-08-26 16:01:25.956669  'ModbusIOException' object has no attribute 'registers'

試しにこの Lambda のコードを少し修正して、（電池を抜いた状態で）直接コマンドラインで実行すると、たしかに数秒待たされてからエラーが標準出力に表示されました。

ということで「センサーからの応答待ち」が原因のようです。pymodbusのドキュメントを見ると「デフォルトのタイムアウトが3秒」であることが分かりました。

そのため、エラー発生時のときも、「ループ処理のsleep(10)の１０秒」と「タイムアウト３秒」の合計で１３秒の空き時間ができていることも分かりました。

2021-08-26 16:01:03.874404  Humidity:   55.2 %
2021-08-26 16:01:16.904751  'ModbusIOException' object has no attribute 'registers'

この時間を変えたい場合は下記のように、タイムアウトを明示的に指定することが可能なようです。

client = ModbusClient(baudrate=9600, port="/dev/ttyUSB0", method="rtu", timeout=5)

試しにタイムアウトを5秒に変更してみます。

client = ModbusClient(baudrate=9600, port="/dev/ttyUSB0", method="rtu")
 ↓
client = ModbusClient(baudrate=9600, port="/dev/ttyUSB0", method="rtu", timeout=5)

次にLambdaコンポーネントのループ内にもsleep(5)を追加してみます。

while True:
    try:
        run_sync_client()
        time.sleep(10)
    except AttributeError as e: # ModbusIOException
        with open(FilePath, 'a') as f:
            print(f"{str(datetime.datetime.now())}\t{str(e)}", file=f)
        time.sleep(5)

期待する結果は「タイムアウト５秒」「 sleep ５秒」の合計１０秒間隔でエラーメッセージも出力されることです。
試してみた結果は下記のとおりです。エラーメッセージも１０秒間隔で出力されるようになりました。

2021-08-26 16:38:46.594753  Temperatur: 28.0 ℃
2021-08-26 16:38:46.594846  Humidity:   54.5 %
2021-08-26 16:38:56.771675  Temperatur: 28.1 ℃
2021-08-26 16:38:56.771772  Humidity:   54.1 %
2021-08-26 16:39:06.819930  Temperatur: 28.1 ℃
2021-08-26 16:39:06.820028  Humidity:   54.0 %
2021-08-26 16:39:21.854715  'ModbusIOException' object has no attribute 'registers'
2021-08-26 16:39:31.876151  'ModbusIOException' object has no attribute 'registers'
2021-08-26 16:39:41.899710  'ModbusIOException' object has no attribute 'registers'
2021-08-26 16:39:51.923579  'ModbusIOException' object has no attribute 'registers'
2021-08-26 16:40:01.951296  'ModbusIOException' object has no attribute 'registers'

AWS 管理コンポーネントである「Modbus プロトコルアダプタ」も内部でpymodbusを利用しているので動作を理解する時に役立ちそうです。

最後に

前回の記事と似たような内容になりましたが、今回は Greengrass デバイスの外部エラーという観点でコンポーネントの動作を確認してみました。

コンポーネントの異常時の動作について２回に分けて検証してみました。次は異常検知の仕組みが気になる所です。
異常発生の検知にはログ監視が有効かと思いますが、軽く調べたところ Greengrass V2 の場合はログマネージャーというコンポーネントが利用できます。まだ検証できていないので次回試してご紹介したいと思います。

以上です。

Share this article

facebook logohatena logotwitter logo

関連記事

SiteWise Edge ゲートウェイのデータ処理パックのアップデートと失敗時の対処方法

SiteWise Edge ゲートウェイのデータ処理パックのアップデートと失敗時の対処方法

User avatar
市田善久
2024.06.06
AWS IoT Greengrass V2 の使い方の基本 〜 Greengrass のインストールからコンポーネントのデプロイまで

AWS IoT Greengrass V2 の使い方の基本 〜 Greengrass のインストールからコンポーネントのデプロイまで

User avatar
市田善久
2023.12.20
DevelopersIO 2023 大阪にて「AWS IoT Greengrass V2で始めるデバイスアプリケーションの継続的開発」というタイトルで発表しました #devio2023

DevelopersIO 2023 大阪にて「AWS IoT Greengrass V2で始めるデバイスアプリケーションの継続的開発」というタイトルで発表しました #devio2023

User avatar
市田善久
2023.07.19
[AWS IoT Greengrass] awslabsで提供されている「AWS Greengrass Labs Certificate Rotator」を使用して証明書のローテーションを試してみました

[AWS IoT Greengrass] awslabsで提供されている「AWS Greengrass Labs Certificate Rotator」を使用して証明書のローテーションを試してみました

User avatar
SIN
2023.07.03
Classmethod's white logo
Facebook's logo
X's logo
YouTube's logo

© Classmethod, Inc. All rights reserved.